<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.0 Transitional//EN"
            "http://www.w3.org/TR/REC-html40/loose.dtd">
<HTML>
<HEAD>



<META http-equiv="Content-Type" content="text/html; charset=ISO-8859-1">
<META name="GENERATOR" content="hevea 1.08">
<LINK rel="stylesheet" type="text/css" href="umsroot.css">
<TITLE>
Timing Profiler
</TITLE>
</HEAD>
<BODY >
<A HREF="umsroot088.html"><IMG SRC ="previous_motif.gif" ALT="Previous"></A>
<A HREF="umsroot083.html"><IMG SRC ="contents_motif.gif" ALT="Up"></A>
<A HREF="umsroot090.html"><IMG SRC ="next_motif.gif" ALT="Next"></A>
<HR>

<H2 CLASS="section"><A NAME="htoc211">15.6</A>&nbsp;&nbsp;Timing Profiler</H2>

<A NAME="@default877"></A> The profiling tool<SUP><A NAME="text24" HREF="umsroot083.html#note24">1</A></SUP> helps to find <EM>hot spots</EM> in
a program that are worth optimising. It can be used any time with any
compiled Prolog code, it is not necessary to use a special compilation
mode or set any flags. Note however that it is not available on
Windows<A NAME="@default878"></A>. When
<BLOCKQUOTE CLASS="quote"><PRE CLASS="verbatim">
?- profile(Goal).
</PRE></BLOCKQUOTE>
<A NAME="@default879"></A> is called, the profiler executes the <EM>Goal</EM> in
the profiling mode, which means that every 100th of a second the
execution is interrupted and the profiler records the currently
executing procedure.<BR>
<BR>
Issuing the following query will result in the profiler recording the
currently executing goal 100 times a second.
<BLOCKQUOTE CLASS="quote"><PRE CLASS="verbatim">
?- profile(queen([1,2,3,4,5,6,7,8,9],Out)).
goal succeeded

                PROFILING STATISTICS
                --------------------

Goal:             queen([1, 2, 3, 4, 5, 6, 7, 8, 9], Out)
Total user time:  0.03s

Predicate             Module        %Time   Time   %Cum
--------------------------------------------------------
qdelete           /4  eclipse       50.0%   0.01s  50.0%
nodiag            /3  eclipse       50.0%   0.01s 100.0%

Out = [1, 3, 6, 8, 2, 4, 9, 7, 5]
Yes (0.14s cpu)
</PRE></BLOCKQUOTE>
From the above result we can see how the profiler output contains four
important areas of information:
<OL CLASS="enumerate" type=1><LI CLASS="li-enumerate">
The first line of output indicates whether the specified goal
<B>succeeded</B>, <B>failed</B> or <B>aborted</B>. The
<CODE>profile/1</CODE> predicate itself always succeeds.
<LI CLASS="li-enumerate">The line beginning <CODE>Goal:</CODE> shows the goal which was
profiled.
<LI CLASS="li-enumerate">The next line shows the time spent executing the goal.
<LI CLASS="li-enumerate">Finally the predicates which were being executed when the
profiler sampled, ranked in decreasing sample count order are shown. 
</OL>
Auxiliary system predicates are printed under a
common name without arity, e.g. <I>arithmetic</I> or <I>all_solutions</I>.
Predicates which are local to locked modules are printed
together on a single line that contains only the module name.
By default only predicates written in Prolog are profiled, i.e.
if a Prolog predicate calls an external or built-in predicate
written in C, the time will be assigned to the Prolog predicate.<BR>
<BR>
The predicate <B>profile(Goal, Flags)</B> can be used to change
the way profiling is made, <I>Flags</I> is a list of flags.
Currently only the flag <TT>simple</TT> is accepted and it
causes separate profiling of simple predicates, i.e.
those written in C.<BR>
<BR>
The problem with the results displayed above is that the sampling
frequency is too low when compared to the total user time spent
executing the goal. In fact in the above example the profiler was
only able to take two samples before the goal terminated.<BR>
<BR>
The frequency at which the profiler samples is fixed, so in order to
obtain more representative results one should have an auxiliary
predicate which calls the goal a number of times, and compile and
profile a call to this auxiliary predicate. eg.
<BLOCKQUOTE CLASS="quote">
<PRE CLASS="verbatim">
queen_100 :-
  (for(_,1,100,1) do queen([1,2,3,4,5,6,7,8,9],_Out)).
</PRE></BLOCKQUOTE>
Note that, when compiled, the above <CODE>do/2</CODE> loop would be
efficiently implemented and not cause overhead that would distort the
measurement. Section <A HREF="umsroot023.html#doloops">5.2</A> presents a 
detailed description of logical loops.
<BLOCKQUOTE CLASS="quote"><PRE CLASS="verbatim">
?- profile(queen_100).
goal succeeded

                PROFILING STATISTICS
                --------------------

Goal:             queen_100
Total user time:  3.19s

Predicate             Module        %Time   Time   %Cum
--------------------------------------------------------
nodiag            /3  eclipse       52.2%   1.67s  52.2%
qdelete           /4  eclipse       27.4%   0.87s  79.6%
qperm             /2  eclipse       17.0%   0.54s  96.5%
safe              /1  eclipse        2.8%   0.09s  99.4%
queen             /2  eclipse        0.6%   0.02s 100.0%

Yes (3.33s cpu)
</PRE></BLOCKQUOTE>
In the above example, the profiler takes over three hundred samples
resulting in a more accurate view of where the time is being spent in
the program. In this instance we can see that more than half of the
time is spent in the <CODE>nodiag/3</CODE> predicate, making it an ideal
candidate for optimisation. This is left as an exercise for the
reader.<BR>
<BR>
<HR>
<A HREF="umsroot088.html"><IMG SRC ="previous_motif.gif" ALT="Previous"></A>
<A HREF="umsroot083.html"><IMG SRC ="contents_motif.gif" ALT="Up"></A>
<A HREF="umsroot090.html"><IMG SRC ="next_motif.gif" ALT="Next"></A>
</BODY>
</HTML>
